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Motivation 


What broke? 


Something doesn't work. Why? 


e It's hard to find out 
e Especially if there is an rfork 


ə An example .. what if on-stack variables 
break? 
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Broken date 


broken date 


Post-july 2010 build on 9vx from updated 
source had problems 


Date would just do nothing 
get impatient, hit return, it worked 


Acme had strange hangs 


Nothing worked 
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Broken date 
oken T 


24577 date Pread 0x19f6 0 Offffee0/"." 8 0 = 
1 "" Ox11cef69ae0b06c68 Ox11cef69c0a58d900 
24577 date Close 0x1a30 0 = 0 "" 
Ox11cef69c0b601f70 0x11cef69c0b607948 
24577 date Open 0x1a89 
0000702c/"/dev/bintime" 00000020 = 0 "" 
Ox11cef69c0c2119c8 0x11c ef69c0c5911e8 

etc. 


e Read from fd 0? What? 


Broken date 


What? : off to code 
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Broken Troff 


term% troff -ms troff.ms | page converting 
from troff to postscript... 


reading through postscript... postnote 1828: 
sys: write on closed pipe pc=0x0001f8fc term% 


e | was not even sure where to start with 
that one 
ə It's a shell pipeline 


ə And somehow the failure on exec got lost 


Broken Troff 


@ Hard to follow this kind of thing. 

ə But: 

e ratrace -c /bin/rc -c “troff -ms troff.ms | 

page” 

e and wait a bit ... 
1938 page Exec 0x2eac 0x279e6/"/bin/gs" 
0x27973/"gs" 0x27976/"-dNOPAUSE" 
0x223f1/"-dSAFER" 
0x27980/"-sDEVICE=plan9" 
0x2798f/"-sOutputFile=/fd/3" 
0x279a2/"-dQUIET" 0x279aa/"-r100" 
Oxdfffcda8/"-dTextAlphaBits=4" 
Oxdfffcd88/"-dGraphicsAlphaBits=4" 
0x279da/"-" = FFFFFFFF 


e So the problem was not the one you might 
have thought: it was just that gs was gone 

e But the error from exec got ignored (only 
observed in the child) 

ə And the parent got the EPIPE 


Trof 
Just use acid, right? 


e It doesn't always work (Blue Gene, 9vx, 
sometimes ARM) 


e But even if you could get it to work 


e Requires a number of local files (painful 
for ram disk setup) 


e But even if you had local files 
ə It’s a pain with fork 
o And even if it was not a pain with fork 


e Well, | just don't find it as convenient as 
ratrace 


How it works 


e Needed a way to tell a program to stop on 
system call entry 


ə Oh wait, it's already there! 
e Need to pretty-print system call args etc. 
@ 9vx led the way 


e 9vx showed that one could dump system 
calls with a simple “boot time” option 


ə So the key was generalize it, make it 
prettier, make it a device 


How it works 


Generalize it 


e The 9vx printing was pretty raw and went 
to the console 


ə Needed to attach the string to a device 


ə So, add a new struct member to proc 
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How it works 


New code 


New proc struct 


New code in syscall 


° 
o 
e New code in devproc 
e New code in proc 

e 


let's go look 
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How it works 


And the ratrace program itself 


A note on interface design 


We can not criticize original ptrace design 


The fact that we are using it forty years 
later, well, that we might be a little harsh 
about 


What does ptrace lead to in real life? 
strace /bin/date 
strace strace /bin/date 
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Comparing ratrace and strace 


rminnich@ratnet:/% strace /bin/date 2>/tmp/x 
Wed Oct 6 15:55:21 PDT 2010 
rminnichOratnet:/$ wc /tmp/x 
71 426 4727 /tmp/x 
rminnich@ratnet:/$ strace 2>/tmp/xx strace 
/bin/date 
Wed Oct 6 15:55:41 PDT 2010 
rminnichOratnet:/$ wc /tmp/xx 
1770 12163 99974 /tmp/xx 

e /bin/date: 71 system calls 

e strace /bin/date: 1770 system calls 

e Factor of 24 blowup 

e strace itself is 58KLOC 


e Most of those calls look like this 


Comparing ratrace and strace 


e looks like 


wait4(4294967295, [{WIFSTOPPED(s) && 
WSTOPSIG(s) == SIGTRAP}], WALL, 
NULL) = 13557 

rt sigprocmask(SIG BLOCK, [HUP INT 
QUIT PIPE TERM], NULL, 8) = 0 
ptrace(PTRACE PEEKUSER, 13557, 
8*ORIG RAX, [0x9]) = 0 

ptrace(PTRACE PEEKUSER, 13557, 8*CS, 
[0x33]) = 0 

ptrace(PTRACE PEEKUSER, 13557, 8*RAX, 
[Oxf FfFFFFFFF FFF da]) = 0 

ptrace(PTRACE PEEKUSER, 13557, 8*RDI, 
[0]) = 0 

ptrace(PTRACE PEEKUSER, 13557, 8*RSI, 
[0x1000]) = 0 

ptrace(PTRACE PEEKUSER, 13557, 8*RDX, 
[0x3]) = 0 

ptrace(PTRACE PEEKUSER, 13557, 8*R10, 
[0x22]) = 0 


aicea PTRACE PEEKUSER,=13557, 8*R8, 


Comparing ratrace and strace 


term% ratrace -c /bin/date 

2054 8.ratrace Open 0x10f9 

Ox1dcc8/" /proc/2056/ctl" 

2054 8.ratrace Pwrite Ox3dle 3 
11b8e/"startsyscall" 12 -0x1 = 0 "" 
0x11da80e80b453ff4 0x11da80e80bfbb71e 
and a Pread, and a Pwrite 

(note: ratracing ratrace is broken in sources, 
help welcome :-) 


e Approximately four system calls per 
syscall. 


Performance 
ir 


term% time ratrace -c /bin/date 

0.00u 0.00s 0.15r ratrace -c /bin/date 
term% time /bin/date 

Thu Oct 7 13:37:31 PDT 2010 0.00u 0.00s 
0.01r /bin/date 

term% 


e Dumb example 


0.00u 0.22s 1.07r ratrace -c /bin/wc 
/rc/bin/0a /rc/bin/0c ... 
term% time wc /rc/bin/* > /dev/null 
0.00u 0.10s 0.12r we /rc/bin/Oa /rc/bin/Oc 
/rc/bin/Ol /rc/bin/9fat: ... 
term% 

e Looks like a factor of 10 


e About the same overhead as for strace 


Summary 


all tracing is easy and can shorten 
lution 


ə Addition to Plan 9 was very 
straightforward 


e Proper interface design leads to compact 
program design and compact operation 


ə Text interface is a good thing 


